JSON formatter #377

pimeys · 2019-10-09T15:58:25Z

Motivation

A formatter for JSON output.

Solution

Enable json feature from tracing-subscriber crate. Instantiate a new formatter with JSON output:

let subscriber = FmtSubscriber::builder()
    .json()
    .with_env_filter(EnvFilter::from_default_env())
    .finish();

subscriber::set_global_default(subscriber)?;

pimeys · 2019-10-09T16:01:35Z

Oh and I just started today with the tracing codebase, so I might not know every detail how this code should be formed. :)

tracing-subscriber/src/fmt/format.rs

tracing-serde/src/lib.rs

tracing-subscriber/src/fmt/format.rs

davidbarsky · 2019-10-10T15:29:47Z

Eugh, sorry about the duplicate comments. Computers!

tracing-subscriber/src/fmt/format.rs

pimeys · 2019-10-10T16:47:19Z

Understood how the Serialize structs work now. Planning to add one for times so we can skip the trimming part in the JSON output. Tomorrow!

tracing-serde/src/lib.rs

tracing-subscriber/Cargo.toml

hawkw

Thanks for making the changes I requested! I left some notes on the structure of the serialized output.

tracing-serde/src/lib.rs

tracing-subscriber/src/fmt/format.rs

hawkw · 2019-10-11T18:25:11Z

tracing-subscriber/src/fmt/format.rs

+            serializer.serialize_entry("timestamp", &timestamp)?;
+            serializer.serialize_entry("level", &meta.level().as_serde())?;
+
+            ctx.with_current(|(_, span)| serializer.serialize_entry("span", span.name()))


this will only serialize the name of the immediate parent span. it seems like it might be good to serialize the span's fields as well — note that if we don't also serialize fields, the JSON formatter will output strictly less information than the text formatter, which does include the parent span's fields.

The current Span implementation in tracing-subscriber formats fields in a format suitable for plain test logs, but looks kind of bad in JSON. See the test example here:

pimeys@b143824#diff-12298a6463a49769f9b40d8e8b01e754R817

I couldn't really track where and why do we stringify the fields in this way. Would be nicer to have a struct that implements Display and AsSerde to the both formats.

The fields are formatted by a type implementing the FormatFields trait:

tracing/tracing-subscriber/src/fmt/format.rs

Lines 49 to 64 in 06daa95

/// A type that can format a [set of fields] to a `fmt::Write`.

///

/// `FormatFields` is primarily used in the context of [`FmtSubscriber`]. Each

/// time a span or event with fields is recorded, the subscriber will format

/// those fields with its associated `FormatFields` implementation.

///

/// [set of fields]: ../field/trait.RecordFields.html

/// [`FmtSubscriber`]: ../fmt/struct.Subscriber.html

pub trait FormatFields<'writer> {

/// Format the provided `fields` to the provided `writer`, returning a result.

fn format_fields<R: RecordFields>(

&self,

writer: &'writer mut dyn fmt::Write,

fields: R,

) -> fmt::Result;

}

The FormatFields implementation used can be set by the Builder here:

tracing/tracing-subscriber/src/fmt/mod.rs

Lines 402 to 433 in 06daa95

/// Sets the Visitor that the subscriber being built will use to record

/// fields.

///

/// For example:

/// ```rust

/// use tracing_subscriber::fmt::{Subscriber, format};

/// use tracing_subscriber::prelude::*;

///

/// let formatter =

/// // Construct a custom formatter for `Debug` fields

/// format::debug_fn(|writer, field, value| write!(writer, "{}: {:?}", field, value))

/// // Use the `tracing_subscriber::MakeFmtExt` trait to wrap the

/// // formatter so that a delimiter is added between fields.

/// .delimited(", ");

///

/// let subscriber = Subscriber::builder()

/// .fmt_fields(formatter)

/// .finish();

/// # drop(subscriber)

/// ```

pub fn fmt_fields<N2>(self, fmt_fields: N2) -> Builder<N2, E, F, W>

where

N2: for<'writer> FormatFields<'writer> + 'static,

{

Builder {

fmt_fields: fmt_fields.into(),

fmt_event: self.fmt_event,

filter: self.filter,

settings: self.settings,

make_writer: self.make_writer,

}

}

FormatFields is also implemented for any MakeVisitor implementation:

tracing/tracing-subscriber/src/fmt/format.rs

Lines 285 to 299 in 06daa95

impl<'writer, M> FormatFields<'writer> for M

where

M: MakeOutput<&'writer mut dyn fmt::Write, fmt::Result>,

M::Visitor: VisitFmt + VisitOutput<fmt::Result>,

{

fn format_fields<R: RecordFields>(

&self,

writer: &'writer mut dyn fmt::Write,

fields: R,

) -> fmt::Result {

let mut v = self.make_visitor(writer);

fields.record(&mut v);

v.finish()

}

}

So, we could override the default field formatter to record the fields using a Serde visitor. Although the formatted representation would be stored as a string, we could then interpolate that string into the output, and the fields would be formatted as JSON.

This is done now but rendering the fields in an escaped form due to serde not really helping us here. We decided in Discord to leave it how it is for now and come back later to fix the architecture to make field formatting better for different formats.

pimeys@53e3394

tracing-subscriber/src/fmt/format.rs

tracing-subscriber/src/lib.rs

hawkw · 2019-10-11T18:27:01Z

tracing-subscriber/Cargo.toml

+# only required by the json feature
+serde_json = { version = "1.0", optional = true }
+serde = { version = "1.0", optional = true }
+tracing-serde = { path = "../tracing-serde", optional = true }


We'll need to publish a tracing-serde release to crates.io before we can publish the changes in this branch — we can't publish a crate that depends on an unpublished crate.

True. Do you have a plan when we want this to happen?

When these changes land, I can take care of that.

tracing-subscriber/src/fmt/format.rs

tracing-core/src/event.rs

hawkw

This looks really close. Beyond moving the WriteAdaptor type out of tracing-serde, I'd be happy to merge this as-is; most of my comments are for follow-up work.

When this merges, it would be good to open new issues to track those follow-ups.

tracing-serde/src/lib.rs

tracing-subscriber/src/fmt/format/json.rs

hawkw · 2019-10-16T18:20:34Z

tracing-subscriber/src/fmt/format/json.rs

+            serializer.serialize_entry("timestamp", &timestamp)?;
+            serializer.serialize_entry("level", &meta.level().as_serde())?;
+
+            ctx.with_current(|(_, span)| serializer.serialize_entry("span", &span))


This serializes only the current span in which the event occurred, rather than the span and all its parents (the way the Format<Full, ...> formatter does. We might want to have separate "full" and "compact" JSON formatters as well (though I'm fine with adding that in a follow-up).

hawkw · 2019-10-16T18:22:12Z

nightly-examples/examples/proxy_server.rs

+        )
+        .get_matches();
+
+    match value_t!(matches, "log_format", LogFormat).unwrap_or(LogFormat::Plain) {


I would still really like it if all of this was factored out of main into a separate function, but it's not a blocker. It would be fine if that function called set_global_default so that we don't have to handle return type issues...

hawkw

This looks good to me! Thanks @pimeys for all your hard work — I know this took a while to get through.

We can ignore the nightly CI failure for now; it's due to a nightly change that broke our CI scripts and is unrelated. I'm going to go ahead and merge this when the other builds are done, and open tickets for some of the follow-up work we discussed.

davidbarsky

@hawkw's review is a more fine-grained superset of mine; I'm happy merging as is!

This reverts commit 3e4c8d9.

Co-Authored-By: Eliza Weisman <[email protected]>

Signed-off-by: Eliza Weisman <[email protected]>

0.2.0 (February 4, 2020) Breaking Changes: - **fmt**: Renamed `Context` to `FmtContext` (#420, #425) - **fmt**: Renamed `Builder` to `SubscriberBuilder` (#420) - **filter**: Removed `Filter`. Use `EnvFilter` instead (#434) Added: - **registry**: `Registry`, a reusable span store that `Layer`s can use a high-performance, in-memory store. (#420, #425, #432, #433, #435) - **registry**: Added `LookupSpan` trait, implemented by `Subscriber`s to expose stored span data to `Layer`s (#420) - **fmt**: Added `fmt::Layer`, to allow composing log formatting with other `Layer`s (#420) - **fmt**: Added support for JSON field and event formatting (#377, #415) - **filter**: Documentation for filtering directives (#554) Changed: - **fmt**: Renamed `Context` to `FmtContext` (#420, #425) (BREAKING) - **fmt**: Renamed `Builder` to `SubscriberBuilder` (#420) (BREAKING) - **fmt**: Reimplemented `fmt::Subscriber` in terms of the `Registry` and `Layer`s (#420) Removed: - **filter**: Removed `Filter`. Use `EnvFilter` instead (#434) (BREAKING) Fixed: - **fmt**: Fixed memory leaks in the slab used to store per-span data (3c35048) - **fmt**: `fmt::SubscriberBuilder::init` not setting up `log` compatibility (#489) - **fmt**: Spans closed by a child span closing not also closing _their_ parents (#514) - **Layer**: Fixed `Layered` subscribers failing to downcast to their own type (#549) - **Layer**: Fixed `Layer::downcast_ref` returning invalid references (#454) Signed-off-by: Eliza Weisman <[email protected]>

# 0.2.0 (February 4, 2020) ### Breaking Changes - **fmt**: Renamed `Context` to `FmtContext` (#420, #425) - **fmt**: Renamed `Builder` to `SubscriberBuilder` (#420) - **filter**: Removed `Filter`. Use `EnvFilter` instead (#434) ### Added - **registry**: `Registry`, a `Subscriber` implementation that `Layer`s can use as a high-performance, in-memory span store. (#420, #425, #432, #433, #435) - **registry**: Added `LookupSpan` trait, implemented by `Subscriber`s to expose stored span data to `Layer`s (#420) - **fmt**: Added `fmt::Layer`, to allow composing log formatting with other `Layer`s - **fmt**: Added support for JSON field and event formatting (#377, #415) - **filter**: Documentation for filtering directives (#554) ### Changed - **fmt**: Renamed `Context` to `FmtContext` (#420, #425) (BREAKING) - **fmt**: Renamed `Builder` to `SubscriberBuilder` (#420) (BREAKING) - **fmt**: Reimplemented `fmt::Subscriber` in terms of the `Registry` and `Layer`s (#420) ### Removed - **filter**: Removed `Filter`. Use `EnvFilter` instead (#434) (BREAKING) ### Fixed - **fmt**: Fixed memory leaks in the slab used to store per-span data (3c35048) - **fmt**: `fmt::SubscriberBuilder::init` not setting up `log` compatibility (#489) - **fmt**: Spans closed by a child span closing not also closing _their_ parents (#514) - **Layer**: Fixed `Layered` subscribers failing to downcast to their own type (#549) - **Layer**: Fixed `Layer::downcast_ref` returning invalid references (#454) Fixes #515 Fixes #458 Signed-off-by: Eliza Weisman <[email protected]>

pimeys mentioned this pull request Oct 9, 2019

tracing-subscriber: JSON formatter #218

Closed

davidbarsky reviewed Oct 9, 2019

View reviewed changes

tracing-subscriber/src/fmt/format.rs Outdated Show resolved Hide resolved

pimeys commented Oct 10, 2019

View reviewed changes

tracing-subscriber/src/fmt/format.rs Outdated Show resolved Hide resolved

pimeys force-pushed the format-json branch from 543e850 to 86ab454 Compare October 10, 2019 13:21

pimeys changed the title ~~WIP: JSON formatter~~ JSON formatter Oct 10, 2019

davidbarsky requested changes Oct 10, 2019

View reviewed changes

tracing-serde/src/lib.rs Outdated Show resolved Hide resolved

tracing-subscriber/src/fmt/format.rs Show resolved Hide resolved

tracing-subscriber/src/fmt/format.rs Outdated Show resolved Hide resolved

tracing-subscriber/src/fmt/format.rs Outdated Show resolved Hide resolved

davidbarsky mentioned this pull request Oct 10, 2019

Provide access to tracing-subscriber::fmt::spans or similar API. #355

Closed

pimeys commented Oct 10, 2019

View reviewed changes

tracing-subscriber/src/fmt/format.rs Outdated Show resolved Hide resolved

pimeys force-pushed the format-json branch from 58ba37e to 357ef3a Compare October 11, 2019 16:18

hawkw reviewed Oct 11, 2019

View reviewed changes

hawkw requested changes Oct 14, 2019

View reviewed changes

tracing-core/src/event.rs Outdated Show resolved Hide resolved

pimeys force-pushed the format-json branch from 38c975e to 53e3394 Compare October 15, 2019 16:52

hawkw reviewed Oct 16, 2019

View reviewed changes

pimeys force-pushed the format-json branch from fb8a113 to 4700b9f Compare October 18, 2019 17:15

hawkw approved these changes Oct 18, 2019

View reviewed changes

hawkw requested a review from davidbarsky October 18, 2019 17:59

davidbarsky approved these changes Oct 18, 2019

View reviewed changes

Julius de Bruijn added 9 commits October 18, 2019 14:10

WIP: JSON formatter

19b5314

Implement JSON formatting using SerdeMapVisitor

de8e931

Better span handling

2857e3f

fmt

c695027

fmt

72615d3

Add newline after json data

f00b0c6

Disable ANSI feature if enabling JSON

1272054

Add a note why we need the WriteAdaptor

4e1ef66

Add a note about the json feature flag

cd51096

Julius de Bruijn and others added 20 commits October 18, 2019 14:10

Revert "Disable ANSI feature if enabling JSON"

8a148ad

This reverts commit 3e4c8d9.

Add note how ansi doesn't work with json

522b963

AsSerde for Level, no extra trim, less allocations

f652a1b

Use a shorter path

b25bdaf

Add json logging to the proxy_server example

cb37cc6

Fixes for @hawkw

abebff2

Update tracing-subscriber/src/lib.rs

7897c53

Co-Authored-By: Eliza Weisman <[email protected]>

Serialize span and fields into separate objects

d831828

Fix compilation problems and tests

3e8bd94

add the ability to serialize fields as a separate map

4117ad3

Signed-off-by: Eliza Weisman <[email protected]>

format fields without requiring tracing-core change

63e8cd6

Signed-off-by: Eliza Weisman <[email protected]>

undo tracing-core change

f1fb716

Signed-off-by: Eliza Weisman <[email protected]>

Almost correct span field recording

013819d

fmt

b1d4b8c

Set logger in a separate function

a1cf246

move WriteAdaptor out of serde crate

c4e9f7f

Signed-off-by: Eliza Weisman <[email protected]>

rustfmt

d72d5a7

Signed-off-by: Eliza Weisman <[email protected]>

fix imports

b6e13ea

Signed-off-by: Eliza Weisman <[email protected]>

fix example not compiling

62c6d5a

Signed-off-by: Eliza Weisman <[email protected]>

fix warnings in example

e53e392

Signed-off-by: Eliza Weisman <[email protected]>

hawkw force-pushed the format-json branch from 524d0eb to e53e392 Compare October 18, 2019 21:12

fix example again

fb42bd2

Signed-off-by: Eliza Weisman <[email protected]>

hawkw merged commit d3e0c06 into tokio-rs:master Oct 18, 2019

hawkw mentioned this pull request Oct 18, 2019

subscriber: don't escape field values in JSON #391

Closed

emschwartz mentioned this pull request Oct 23, 2019

Add tracing for ilp-node interledger/interledger-rs#457

Merged

hawkw mentioned this pull request Feb 4, 2020

subscriber: prepare to release 0.2.0 stable #567

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

JSON formatter #377

JSON formatter #377

pimeys commented Oct 9, 2019 •

edited

Loading

pimeys commented Oct 9, 2019 •

edited

Loading

davidbarsky commented Oct 10, 2019

pimeys commented Oct 10, 2019

hawkw left a comment

hawkw Oct 11, 2019

pimeys Oct 14, 2019

hawkw Oct 14, 2019

pimeys Oct 15, 2019

pimeys Oct 16, 2019

hawkw Oct 11, 2019

pimeys Oct 12, 2019

hawkw Oct 12, 2019

hawkw left a comment

hawkw Oct 16, 2019

hawkw Oct 16, 2019

hawkw left a comment

davidbarsky left a comment

	/// A type that can format a [set of fields] to a `fmt::Write`.
	///
	/// `FormatFields` is primarily used in the context of [`FmtSubscriber`]. Each
	/// time a span or event with fields is recorded, the subscriber will format
	/// those fields with its associated `FormatFields` implementation.
	///
	/// [set of fields]: ../field/trait.RecordFields.html
	/// [`FmtSubscriber`]: ../fmt/struct.Subscriber.html
	pub trait FormatFields<'writer> {
	/// Format the provided `fields` to the provided `writer`, returning a result.
	fn format_fields<R: RecordFields>(
	&self,
	writer: &'writer mut dyn fmt::Write,
	fields: R,
	) -> fmt::Result;
	}

	/// Sets the Visitor that the subscriber being built will use to record
	/// fields.
	///
	/// For example:
	/// ```rust
	/// use tracing_subscriber::fmt::{Subscriber, format};
	/// use tracing_subscriber::prelude::*;
	///
	/// let formatter =
	/// // Construct a custom formatter for `Debug` fields
	/// format::debug_fn(\|writer, field, value\| write!(writer, "{}: {:?}", field, value))
	/// // Use the `tracing_subscriber::MakeFmtExt` trait to wrap the
	/// // formatter so that a delimiter is added between fields.
	/// .delimited(", ");
	///
	/// let subscriber = Subscriber::builder()
	/// .fmt_fields(formatter)
	/// .finish();
	/// # drop(subscriber)
	/// ```
	pub fn fmt_fields<N2>(self, fmt_fields: N2) -> Builder<N2, E, F, W>
	where
	N2: for<'writer> FormatFields<'writer> + 'static,
	{
	Builder {
	fmt_fields: fmt_fields.into(),
	fmt_event: self.fmt_event,
	filter: self.filter,
	settings: self.settings,
	make_writer: self.make_writer,
	}
	}

	impl<'writer, M> FormatFields<'writer> for M
	where
	M: MakeOutput<&'writer mut dyn fmt::Write, fmt::Result>,
	M::Visitor: VisitFmt + VisitOutput<fmt::Result>,
	{
	fn format_fields<R: RecordFields>(
	&self,
	writer: &'writer mut dyn fmt::Write,
	fields: R,
	) -> fmt::Result {
	let mut v = self.make_visitor(writer);
	fields.record(&mut v);
	v.finish()
	}
	}

JSON formatter #377

JSON formatter #377

Conversation

pimeys commented Oct 9, 2019 • edited Loading

Motivation

Solution

pimeys commented Oct 9, 2019 • edited Loading

davidbarsky commented Oct 10, 2019

pimeys commented Oct 10, 2019

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hawkw left a comment

Choose a reason for hiding this comment

davidbarsky left a comment

Choose a reason for hiding this comment

pimeys commented Oct 9, 2019 •

edited

Loading

pimeys commented Oct 9, 2019 •

edited

Loading